Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

refactor(network): move unclean disconnect log to debug #5541

Merged
merged 1 commit into from
May 26, 2023
Merged

refactor(network): move unclean disconnect log to debug #5541

merged 1 commit into from
May 26, 2023

Conversation

nflaig
Copy link
Member

@nflaig nflaig commented May 25, 2023

Motivation

#5359 (comment)

Description

Move unclean disconnect log to from warn to debug

@nflaig nflaig requested a review from a team as a code owner May 25, 2023 13:09
nflaig
nflaig commented May 25, 2023
View reviewed changes
packages/beacon-node/src/network/peers/peerManager.ts
@@ -628,7 +628,7 @@ export class PeerManager {
try {
await this.libp2p.hangUp(peer);
} catch (e) {
this.logger.warn("Unclean disconnect", {peer: prettyPrintPeerId(peer)}, e as Error);
this.logger.debug("Unclean disconnect", {peer: prettyPrintPeerId(peer)}, e as Error);
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Anyone knows why prettyPrintPeerId only prints out the first 2 characters? Those seem to be always 16 , e.g. peer=16...LaZW3U.

I saw users wonder why peer 16 is always disconnecting 🤔

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yeah that's a good question. For this context I suppose we should print the whole peer id as it's for developer, not for user. We can ask other client for a specific peer id for example

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Moving this from warn to debug will solve most of the confusion for users as most do not look at debug logs. We are using prettyPrintPeerId all over the place in peer manager, maybe could print first 4 characters instead of just 2.

We can ask other client for a specific peer id for example

Not sure how they would look up the peer id but would assume if it just based on searching the logs it should even be sufficient to just have the truncated peer id.

Anyways, changes on how we want to log the peer ids should probably be addressed in another PR.

@nflaig nflaig mentioned this pull request May 25, 2023
Closed
@github-actions
Copy link
Contributor

Performance Report

✔️ no performance regression detected

Full benchmark results
Benchmark suite Current: bed4ed0 Previous: 8023e3f Ratio
getPubkeys - index2pubkey - req 1000 vs - 250000 vc 572.62 us/op 693.94 us/op 0.83
getPubkeys - validatorsArr - req 1000 vs - 250000 vc 49.529 us/op 43.906 us/op 1.13
BLS verify - blst-native 1.2459 ms/op 1.1938 ms/op 1.04
BLS verifyMultipleSignatures 3 - blst-native 2.5439 ms/op 2.4301 ms/op 1.05
BLS verifyMultipleSignatures 8 - blst-native 5.4829 ms/op 5.2494 ms/op 1.04
BLS verifyMultipleSignatures 32 - blst-native 19.763 ms/op 18.786 ms/op 1.05
BLS aggregatePubkeys 32 - blst-native 26.368 us/op 24.871 us/op 1.06
BLS aggregatePubkeys 128 - blst-native 102.89 us/op 96.683 us/op 1.06
getAttestationsForBlock 59.130 ms/op 52.053 ms/op 1.14
isKnown best case - 1 super set check 269.00 ns/op 239.00 ns/op 1.13
isKnown normal case - 2 super set checks 259.00 ns/op 235.00 ns/op 1.10
isKnown worse case - 16 super set checks 255.00 ns/op 232.00 ns/op 1.10
CheckpointStateCache - add get delete 5.1210 us/op 4.8620 us/op 1.05
validate gossip signedAggregateAndProof - struct 2.8131 ms/op 2.7041 ms/op 1.04
validate gossip attestation - struct 1.3409 ms/op 1.2893 ms/op 1.04
pickEth1Vote - no votes 1.3147 ms/op 1.1707 ms/op 1.12
pickEth1Vote - max votes 10.753 ms/op 10.295 ms/op 1.04
pickEth1Vote - Eth1Data hashTreeRoot value x2048 9.2397 ms/op 8.8280 ms/op 1.05
pickEth1Vote - Eth1Data hashTreeRoot tree x2048 14.028 ms/op 14.497 ms/op 0.97
pickEth1Vote - Eth1Data fastSerialize value x2048 642.27 us/op 621.62 us/op 1.03
pickEth1Vote - Eth1Data fastSerialize tree x2048 6.5828 ms/op 7.1393 ms/op 0.92
bytes32 toHexString 564.00 ns/op 491.00 ns/op 1.15
bytes32 Buffer.toString(hex) 400.00 ns/op 348.00 ns/op 1.15
bytes32 Buffer.toString(hex) from Uint8Array 612.00 ns/op 541.00 ns/op 1.13
bytes32 Buffer.toString(hex) + 0x 404.00 ns/op 347.00 ns/op 1.16
Object access 1 prop 0.18500 ns/op 0.15900 ns/op 1.16
Map access 1 prop 0.17000 ns/op 0.15400 ns/op 1.10
Object get x1000 6.9460 ns/op 6.4350 ns/op 1.08
Map get x1000 0.67700 ns/op 0.50700 ns/op 1.34
Object set x1000 72.238 ns/op 50.638 ns/op 1.43
Map set x1000 53.307 ns/op 42.559 ns/op 1.25
Return object 10000 times 0.24800 ns/op 0.23160 ns/op 1.07
Throw Error 10000 times 4.3097 us/op 4.3255 us/op 1.00
fastMsgIdFn sha256 / 200 bytes 3.6020 us/op 3.4150 us/op 1.05
fastMsgIdFn h32 xxhash / 200 bytes 317.00 ns/op 274.00 ns/op 1.16
fastMsgIdFn h64 xxhash / 200 bytes 471.00 ns/op 393.00 ns/op 1.20
fastMsgIdFn sha256 / 1000 bytes 11.938 us/op 11.311 us/op 1.06
fastMsgIdFn h32 xxhash / 1000 bytes 454.00 ns/op 397.00 ns/op 1.14
fastMsgIdFn h64 xxhash / 1000 bytes 568.00 ns/op 456.00 ns/op 1.25
fastMsgIdFn sha256 / 10000 bytes 105.67 us/op 101.22 us/op 1.04
fastMsgIdFn h32 xxhash / 10000 bytes 2.0030 us/op 1.8700 us/op 1.07
fastMsgIdFn h64 xxhash / 10000 bytes 1.3460 us/op 1.3420 us/op 1.00
enrSubnets - fastDeserialize 64 bits 1.6940 us/op 1.2480 us/op 1.36
enrSubnets - ssz BitVector 64 bits 637.00 ns/op 490.00 ns/op 1.30
enrSubnets - fastDeserialize 4 bits 211.00 ns/op 167.00 ns/op 1.26
enrSubnets - ssz BitVector 4 bits 656.00 ns/op 500.00 ns/op 1.31
prioritizePeers score -10:0 att 32-0.1 sync 2-0 119.84 us/op 104.75 us/op 1.14
prioritizePeers score 0:0 att 32-0.25 sync 2-0.25 164.64 us/op 127.70 us/op 1.29
prioritizePeers score 0:0 att 32-0.5 sync 2-0.5 199.69 us/op 164.40 us/op 1.21
prioritizePeers score 0:0 att 64-0.75 sync 4-0.75 364.72 us/op 296.33 us/op 1.23
prioritizePeers score 0:0 att 64-1 sync 4-1 445.65 us/op 354.98 us/op 1.26
array of 16000 items push then shift 1.6894 us/op 1.5985 us/op 1.06
LinkedList of 16000 items push then shift 10.253 ns/op 8.5960 ns/op 1.19
array of 16000 items push then pop 132.06 ns/op 72.575 ns/op 1.82
LinkedList of 16000 items push then pop 9.3790 ns/op 8.3350 ns/op 1.13
array of 24000 items push then shift 2.4561 us/op 2.3140 us/op 1.06
LinkedList of 24000 items push then shift 10.882 ns/op 8.6270 ns/op 1.26
array of 24000 items push then pop 89.593 ns/op 74.672 ns/op 1.20
LinkedList of 24000 items push then pop 8.8560 ns/op 8.2960 ns/op 1.07
intersect bitArray bitLen 8 14.824 ns/op 12.940 ns/op 1.15
intersect array and set length 8 82.751 ns/op 75.301 ns/op 1.10
intersect bitArray bitLen 128 45.825 ns/op 42.941 ns/op 1.07
intersect array and set length 128 1.0954 us/op 1.0216 us/op 1.07
Buffer.concat 32 items 2.9670 us/op 2.7520 us/op 1.08
Uint8Array.set 32 items 2.2210 us/op 2.8780 us/op 0.77
pass gossip attestations to forkchoice per slot 2.7393 ms/op 2.5406 ms/op 1.08
computeDeltas 3.0582 ms/op 2.9213 ms/op 1.05
computeProposerBoostScoreFromBalances 1.8022 ms/op 1.7656 ms/op 1.02
altair processAttestation - 250000 vs - 7PWei normalcase 2.7208 ms/op 2.1536 ms/op 1.26
altair processAttestation - 250000 vs - 7PWei worstcase 3.4813 ms/op 3.2837 ms/op 1.06
altair processAttestation - setStatus - 1/6 committees join 146.68 us/op 141.13 us/op 1.04
altair processAttestation - setStatus - 1/3 committees join 281.77 us/op 277.02 us/op 1.02
altair processAttestation - setStatus - 1/2 committees join 379.12 us/op 379.99 us/op 1.00
altair processAttestation - setStatus - 2/3 committees join 474.62 us/op 453.38 us/op 1.05
altair processAttestation - setStatus - 4/5 committees join 675.65 us/op 630.11 us/op 1.07
altair processAttestation - setStatus - 100% committees join 802.45 us/op 766.46 us/op 1.05
altair processBlock - 250000 vs - 7PWei normalcase 16.915 ms/op 16.493 ms/op 1.03
altair processBlock - 250000 vs - 7PWei normalcase hashState 27.317 ms/op 24.479 ms/op 1.12
altair processBlock - 250000 vs - 7PWei worstcase 50.898 ms/op 45.008 ms/op 1.13
altair processBlock - 250000 vs - 7PWei worstcase hashState 69.378 ms/op 63.973 ms/op 1.08
phase0 processBlock - 250000 vs - 7PWei normalcase 2.4499 ms/op 2.2482 ms/op 1.09
phase0 processBlock - 250000 vs - 7PWei worstcase 32.037 ms/op 29.608 ms/op 1.08
altair processEth1Data - 250000 vs - 7PWei normalcase 484.22 us/op 456.35 us/op 1.06
getExpectedWithdrawals 250000 eb:1,eth1:1,we:0,wn:0,smpl:15 10.533 us/op 7.3720 us/op 1.43
getExpectedWithdrawals 250000 eb:0.95,eth1:0.1,we:0.05,wn:0,smpl:219 31.795 us/op 23.698 us/op 1.34
getExpectedWithdrawals 250000 eb:0.95,eth1:0.3,we:0.05,wn:0,smpl:42 12.343 us/op 12.541 us/op 0.98
getExpectedWithdrawals 250000 eb:0.95,eth1:0.7,we:0.05,wn:0,smpl:18 9.0180 us/op 6.4850 us/op 1.39
getExpectedWithdrawals 250000 eb:0.1,eth1:0.1,we:0,wn:0,smpl:1020 122.52 us/op 96.080 us/op 1.28
getExpectedWithdrawals 250000 eb:0.03,eth1:0.03,we:0,wn:0,smpl:11777 923.30 us/op 670.57 us/op 1.38
getExpectedWithdrawals 250000 eb:0.01,eth1:0.01,we:0,wn:0,smpl:16384 916.11 us/op 912.98 us/op 1.00
getExpectedWithdrawals 250000 eb:0,eth1:0,we:0,wn:0,smpl:16384 910.21 us/op 935.93 us/op 0.97
getExpectedWithdrawals 250000 eb:0,eth1:0,we:0,wn:0,nocache,smpl:16384 2.4625 ms/op 2.3541 ms/op 1.05
getExpectedWithdrawals 250000 eb:0,eth1:1,we:0,wn:0,smpl:16384 1.7271 ms/op 1.4986 ms/op 1.15
getExpectedWithdrawals 250000 eb:0,eth1:1,we:0,wn:0,nocache,smpl:16384 4.4201 ms/op 3.7318 ms/op 1.18
Tree 40 250000 create 310.72 ms/op 300.09 ms/op 1.04
Tree 40 250000 get(125000) 189.85 ns/op 175.67 ns/op 1.08
Tree 40 250000 set(125000) 961.59 ns/op 962.32 ns/op 1.00
Tree 40 250000 toArray() 20.356 ms/op 17.448 ms/op 1.17
Tree 40 250000 iterate all - toArray() + loop 19.846 ms/op 17.434 ms/op 1.14
Tree 40 250000 iterate all - get(i) 72.265 ms/op 65.000 ms/op 1.11
MutableVector 250000 create 9.8942 ms/op 10.570 ms/op 0.94
MutableVector 250000 get(125000) 7.1380 ns/op 6.0340 ns/op 1.18
MutableVector 250000 set(125000) 263.26 ns/op 256.60 ns/op 1.03
MutableVector 250000 toArray() 3.1403 ms/op 2.7218 ms/op 1.15
MutableVector 250000 iterate all - toArray() + loop 3.4055 ms/op 2.8715 ms/op 1.19
MutableVector 250000 iterate all - get(i) 1.5383 ms/op 1.4879 ms/op 1.03
Array 250000 create 2.8209 ms/op 2.5793 ms/op 1.09
Array 250000 clone - spread 1.1710 ms/op 1.3170 ms/op 0.89
Array 250000 get(125000) 0.56400 ns/op 0.59200 ns/op 0.95
Array 250000 set(125000) 0.64700 ns/op 0.67600 ns/op 0.96
Array 250000 iterate all - loop 111.07 us/op 81.959 us/op 1.36
effectiveBalanceIncrements clone Uint8Array 300000 41.415 us/op 28.516 us/op 1.45
effectiveBalanceIncrements clone MutableVector 300000 364.00 ns/op 401.00 ns/op 0.91
effectiveBalanceIncrements rw all Uint8Array 300000 175.36 us/op 164.86 us/op 1.06
effectiveBalanceIncrements rw all MutableVector 300000 81.913 ms/op 82.424 ms/op 0.99
phase0 afterProcessEpoch - 250000 vs - 7PWei 116.28 ms/op 110.44 ms/op 1.05
phase0 beforeProcessEpoch - 250000 vs - 7PWei 40.952 ms/op 32.505 ms/op 1.26
altair processEpoch - mainnet_e81889 303.75 ms/op 299.36 ms/op 1.01
mainnet_e81889 - altair beforeProcessEpoch 49.526 ms/op 63.111 ms/op 0.78
mainnet_e81889 - altair processJustificationAndFinalization 17.308 us/op 17.101 us/op 1.01
mainnet_e81889 - altair processInactivityUpdates 5.6911 ms/op 5.0986 ms/op 1.12
mainnet_e81889 - altair processRewardsAndPenalties 66.721 ms/op 53.297 ms/op 1.25
mainnet_e81889 - altair processRegistryUpdates 2.5130 us/op 2.1810 us/op 1.15
mainnet_e81889 - altair processSlashings 615.00 ns/op 563.00 ns/op 1.09
mainnet_e81889 - altair processEth1DataReset 517.00 ns/op 564.00 ns/op 0.92
mainnet_e81889 - altair processEffectiveBalanceUpdates 1.2761 ms/op 1.2230 ms/op 1.04
mainnet_e81889 - altair processSlashingsReset 4.4190 us/op 4.8860 us/op 0.90
mainnet_e81889 - altair processRandaoMixesReset 4.3980 us/op 4.6680 us/op 0.94
mainnet_e81889 - altair processHistoricalRootsUpdate 606.00 ns/op 631.00 ns/op 0.96
mainnet_e81889 - altair processParticipationFlagUpdates 2.4160 us/op 2.4420 us/op 0.99
mainnet_e81889 - altair processSyncCommitteeUpdates 1.1240 us/op 601.00 ns/op 1.87
mainnet_e81889 - altair afterProcessEpoch 121.11 ms/op 116.38 ms/op 1.04
phase0 processEpoch - mainnet_e58758 323.61 ms/op 314.60 ms/op 1.03
mainnet_e58758 - phase0 beforeProcessEpoch 139.97 ms/op 117.64 ms/op 1.19
mainnet_e58758 - phase0 processJustificationAndFinalization 29.008 us/op 17.376 us/op 1.67
mainnet_e58758 - phase0 processRewardsAndPenalties 56.005 ms/op 56.746 ms/op 0.99
mainnet_e58758 - phase0 processRegistryUpdates 8.3050 us/op 7.7620 us/op 1.07
mainnet_e58758 - phase0 processSlashings 559.00 ns/op 549.00 ns/op 1.02
mainnet_e58758 - phase0 processEth1DataReset 666.00 ns/op 577.00 ns/op 1.15
mainnet_e58758 - phase0 processEffectiveBalanceUpdates 1.0235 ms/op 943.72 us/op 1.08
mainnet_e58758 - phase0 processSlashingsReset 4.4230 us/op 2.8700 us/op 1.54
mainnet_e58758 - phase0 processRandaoMixesReset 6.6320 us/op 4.6390 us/op 1.43
mainnet_e58758 - phase0 processHistoricalRootsUpdate 1.7260 us/op 591.00 ns/op 2.92
mainnet_e58758 - phase0 processParticipationRecordUpdates 5.6930 us/op 4.1100 us/op 1.39
mainnet_e58758 - phase0 afterProcessEpoch 95.872 ms/op 94.123 ms/op 1.02
phase0 processEffectiveBalanceUpdates - 250000 normalcase 1.3704 ms/op 1.1762 ms/op 1.17
phase0 processEffectiveBalanceUpdates - 250000 worstcase 0.5 1.5764 ms/op 1.4426 ms/op 1.09
altair processInactivityUpdates - 250000 normalcase 26.682 ms/op 20.007 ms/op 1.33
altair processInactivityUpdates - 250000 worstcase 27.118 ms/op 20.297 ms/op 1.34
phase0 processRegistryUpdates - 250000 normalcase 10.539 us/op 6.1970 us/op 1.70
phase0 processRegistryUpdates - 250000 badcase_full_deposits 336.63 us/op 226.62 us/op 1.49
phase0 processRegistryUpdates - 250000 worstcase 0.5 133.43 ms/op 104.82 ms/op 1.27
altair processRewardsAndPenalties - 250000 normalcase 66.695 ms/op 50.119 ms/op 1.33
altair processRewardsAndPenalties - 250000 worstcase 76.584 ms/op 47.560 ms/op 1.61
phase0 getAttestationDeltas - 250000 normalcase 7.1817 ms/op 6.3397 ms/op 1.13
phase0 getAttestationDeltas - 250000 worstcase 7.3403 ms/op 6.3867 ms/op 1.15
phase0 processSlashings - 250000 worstcase 3.7898 ms/op 3.5070 ms/op 1.08
altair processSyncCommitteeUpdates - 250000 188.12 ms/op 175.10 ms/op 1.07
BeaconState.hashTreeRoot - No change 343.00 ns/op 256.00 ns/op 1.34
BeaconState.hashTreeRoot - 1 full validator 57.780 us/op 48.850 us/op 1.18
BeaconState.hashTreeRoot - 32 full validator 572.21 us/op 490.34 us/op 1.17
BeaconState.hashTreeRoot - 512 full validator 6.1415 ms/op 5.5673 ms/op 1.10
BeaconState.hashTreeRoot - 1 validator.effectiveBalance 68.908 us/op 58.520 us/op 1.18
BeaconState.hashTreeRoot - 32 validator.effectiveBalance 1.0846 ms/op 832.36 us/op 1.30
BeaconState.hashTreeRoot - 512 validator.effectiveBalance 16.660 ms/op 10.731 ms/op 1.55
BeaconState.hashTreeRoot - 1 balances 51.907 us/op 46.560 us/op 1.11
BeaconState.hashTreeRoot - 32 balances 475.88 us/op 434.67 us/op 1.09
BeaconState.hashTreeRoot - 512 balances 4.6673 ms/op 4.3013 ms/op 1.09
BeaconState.hashTreeRoot - 250000 balances 76.626 ms/op 74.902 ms/op 1.02
aggregationBits - 2048 els - zipIndexesInBitList 17.148 us/op 15.990 us/op 1.07
regular array get 100000 times 38.549 us/op 31.263 us/op 1.23
wrappedArray get 100000 times 33.971 us/op 31.252 us/op 1.09
arrayWithProxy get 100000 times 17.197 ms/op 15.427 ms/op 1.11
ssz.Root.equals 567.00 ns/op 534.00 ns/op 1.06
byteArrayEquals 564.00 ns/op 533.00 ns/op 1.06
shuffle list - 16384 els 7.1278 ms/op 6.5768 ms/op 1.08
shuffle list - 250000 els 103.53 ms/op 96.283 ms/op 1.08
processSlot - 1 slots 8.9470 us/op 8.2020 us/op 1.09
processSlot - 32 slots 1.4112 ms/op 1.2745 ms/op 1.11
getEffectiveBalanceIncrementsZeroInactive - 250000 vs - 7PWei 35.340 ms/op 32.970 ms/op 1.07
getCommitteeAssignments - req 1 vs - 250000 vc 3.0113 ms/op 2.8064 ms/op 1.07
getCommitteeAssignments - req 100 vs - 250000 vc 4.2909 ms/op 3.9887 ms/op 1.08
getCommitteeAssignments - req 1000 vs - 250000 vc 4.7434 ms/op 4.3331 ms/op 1.09
RootCache.getBlockRootAtSlot - 250000 vs - 7PWei 5.2000 ns/op 4.3000 ns/op 1.21
state getBlockRootAtSlot - 250000 vs - 7PWei 653.89 ns/op 758.98 ns/op 0.86
computeProposers - vc 250000 11.974 ms/op 9.7152 ms/op 1.23
computeEpochShuffling - vc 250000 107.16 ms/op 96.623 ms/op 1.11
getNextSyncCommittee - vc 250000 189.67 ms/op 168.61 ms/op 1.12
computeSigningRoot for AttestationData 14.844 us/op 12.832 us/op 1.16
hash AttestationData serialized data then Buffer.toString(base64) 2.5737 us/op 2.3905 us/op 1.08
toHexString serialized data 1.3529 us/op 1.0628 us/op 1.27
Buffer.toString(base64) 356.54 ns/op 306.05 ns/op 1.16

by benchmarkbot/action

@nflaig nflaig merged commit a42885d into unstable May 26, 2023
@nflaig nflaig deleted the nflaig/unclean-disconnect-to-debug branch May 26, 2023 12:54
@wemeetagain
Copy link
Member

🎉 This PR is included in v1.9.0 🎉

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@twoeths twoeths twoeths approved these changes

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
3 participants
@nflaig @wemeetagain @twoeths